https://authzed.com logo
Join Discord
Powered by
so... even restarting both, spicedb and postgres, ...
# spicedb
p
so... even restarting both, spicedb and postgres, doesnt affect the issue
j
you'll need to run SpiceDB with 
--log-level=trace
and send logs when it happens; they might provide some insight
p
will do
could it also be something related to time-zones?
ok... this is a bit odd... I've seen in the log following thing:
Copy code
5:30PM INF Query args=[] module=pgx pid=44492 rowCount=1 sql="SELECT NOW()"
5:30PM INF Query args=["2022-03-19T17:30:45.838271Z"] module=pgx pid=44492 rowCount=1 sql="SELECT MAX(id) FROM relation_tuple_transaction WHERE timestamp < $1"
5:30PM INF Exec args=[117] commandTag=REVMRVRFIDA= module=pgx pid=44492 sql="WITH rows AS (SELECT id FROM relation_tuple WHERE deleted_transaction <= $1)\n\t\t  DELETE FROM relation_tuple\n\t\t  WHERE id IN (SELECT id FROM rows);\n\t"
5:30PM INF Exec args=[117] commandTag=REVMRVRFIDA= module=pgx pid=44492 sql="WITH rows AS (SELECT id FROM relation_tuple_transaction WHERE id < $1)\n\t\t  DELETE FROM relation_tuple_transaction\n\t\t  WHERE id IN (SELECT id FROM rows);\n\t"
This seems to be the call where it essentially removes old cache stuff (idk) What I'm confused about is that 117... in the realtion_tuple table i have found these entries related to the admin relation
and in the realtion_tuple_transaction table i've found this for id 117 (yesterday and different time)
thats probably not it... seems like spicedb does that every now and then and not after a couple of seconds...
Copy code
5:37PM INF started call grpc.code=OK grpc.component=server grpc.method=CheckPermission grpc.method_type=unary grpc.service=authzed.api.v1.PermissionsService grpc.start_time=2022-03-20T17:37:49Z grpc.time_ms=0.016 peer.address=172.17.0.1:43426 protocol=grpc requestID=5d7b32b1c1b31969f070cb6518fd1e8d
5:37PM INF Query args=[] module=pgx pid=44492 rowCount=1 sql="SELECT NOW()"
5:37PM INF Query args=["2022-03-20T17:37:45.130627Z"] module=pgx pid=44492 rowCount=1 sql="SELECT MIN(id), MAX(id) FROM relation_tuple_transaction WHERE timestamp >= $1"
5:37PM TRC adding sample duration to statistics duration=3.107615 requestID=5d7b32b1c1b31969f070cb6518fd1e8d
5:37PM INF finished call grpc.code=OK grpc.component=server grpc.method=CheckPermission grpc.method_type=unary grpc.service=authzed.api.v1.PermissionsService grpc.start_time=2022-03-20T17:37:49Z grpc.time_ms=3.569 peer.address=172.17.0.1:43426 protocol=grpc requestID=5d7b32b1c1b31969f070cb6518fd1e8d
This is btw the output when i reques to check the permission for edit_tags, while it should return true because the relation should exist, but instead it returned false
I new comletely cleaned up my DB and migrated new to setup the tables etc then I've set the schema
i then just added the relation 
global:0#admin@user:1484971115573936128
the permission check 
global:0#edit_tags@user:1484971115573936128
results in either 
false
or an error `Error: rpc error: code = FailedPrecondition desc = failed precondition: object definition 
global
not found`
relation is now
Copy code
definition user {
        // relation global: global
        relation self: user
}

definition global {
        relation admin: user
        permission edit_tags = admin
        permission moderate_users = admin
}

definition package {
        relation global: global
        relation owner: user
        permission write = owner
        permission moderate = global->admin
        permission view_all = write + moderate
}

definition release {
        relation package: package
        permission write = package->write
        permission moderate = package->moderate
        permission view_all = write + moderate
}
(i removed the user global thingy because maybe that influenced it, apperently it didnt)
my tables in the database:
relation_tuple
relation_tuple_transaction
namespace_config
alembic_version
The log of the SpiceDB instance (i made a couple of permission checks before setting the schema, after it but before adding the relation, and a couple of checks after i added the realtion)
message
so after 10min is still have the same behaviour
j
the schema saying its not found is expected briefly when using the cache
p
okay... i think its time zones
j
["2022-03-19T17:54:36.851157Z"]
yep
p
i just went ahead and changed all timestamps inside the relation_tuple_transaction, to be one hour earlier (which would match my timezone) and now it returns solid true
j
okay
so yeah, its a clock issue
the question is why
maybe spring forward issue?
p
?
j
Daylight savings vs standard time
if it is one hour off
p
ah
no.
j
all the times should be in UTC, in theory
the query being made says 03-19-2022, but the table has 03-20-2022
p
I'm located in germany... we have daylight savings but right now its winter time so we are CET
j
which seems to indicate the table is properly storing UTC times
did Germany switch over yet?
p
not yet
j
nah
that's next week
p
we are just CET = UTC+1 (right now)
j
aha
okay, so then yeah, its something with the times being pulled from Postgres vs the time SpiceDB is using
what does 
SELECT NOW()
in your DB return?
is it UTC or CET?
p
CET
j
okay
so it returns it with the proper timezone
and the times in 
relation_tuple_transaction
should be in UTC
but can you create a new relationship
and see what 
select * from relation_tuple_transaction
shows for the new transaction's timestamp?
let's make sure it is in UTC
p
Side Note: WSL2 (debian) command 
date
returns 
Sun 20 Mar 2022 07:10:34 PM CET
j
which looks right
p
its CET
i dont know tho, if pgAdmin translates timestamps into the current timezone....
the whole table
j
hmm
p
huh
i dont have the issue there
(with the new relation)
j
that's odd
p
sec... gonna delete it
delete transaction again CET timestamp
but permission check so far returns true (should be false)
j
the real question is whether its using that new transaction ID
p
j
sure
I meant for the checks
> 5:50PM INF Query args=[6,9223372036854775807,"6"] module=pgx pid=45284 rowCount=4 sql="SELECT serialized_config, created_transaction FROM namespace_config WHERE created_transaction $3)"
a line like that will show which ID it is using
(in that case ^ 
6
)
it should be using 
8
now
p
Copy code
6:17PM INF started call grpc.code=OK grpc.component=server grpc.method=CheckPermission grpc.method_type=unary grpc.service=authzed.api.v1.PermissionsService grpc.start_time=2022-03-20T18:17:33Z grpc.time_ms=0.02 peer.address=172.17.0.1:43792 protocol=grpc requestID=d0345fefabf7f9baa000a6ca2e5256e8
6:17PM INF Query args=[] module=pgx pid=46304 rowCount=1 sql="SELECT NOW()"
6:17PM INF Query args=["2022-03-20T18:17:29.443729Z"] module=pgx pid=46304 rowCount=1 sql="SELECT MIN(id), MAX(id) FROM relation_tuple_transaction WHERE timestamp >= $1"
6:17PM TRC adding sample duration to statistics duration=5.889633 requestID=d0345fefabf7f9baa000a6ca2e5256e8
6:17PM INF finished call grpc.code=OK grpc.component=server grpc.method=CheckPermission grpc.method_type=unary grpc.service=authzed.api.v1.PermissionsService grpc.start_time=2022-03-20T18:17:33Z grpc.time_ms=6.397 peer.address=172.17.0.1:43792 protocol=grpc requestID=d0345fefabf7f9baa000a6ca2e5256e8
j
that's using the cache
2022-03-20T18:17:29.443729Z
what does 
SELECT MIN(id), MAX(id) FROM relation_tuple_transaction WHERE timestamp >= "2022-03-20T18:17:29.443729Z"
return?
p
I'm not a expert in SQL... it complains about the timeliteral and says the column "timestamp here" doesnt exist xD
ah
single qote did it
j
ah
p
j
okay
I think that's the issue
p
ah
j
it should only be returning for transaction #8 after a few seconds
but the timestamp is wrong for some reason
so its including the older transaction
p
https://www.postgresql.org/docs/9.1/datatype-datetime.html maybe... changing the column of the timestamp to "with time zone" helps
mhmhm... nah... okay... it's not as simple as just changing the column to be with time zone xD
j
no
I think what's happening is that 
NOW()
is returning the time with timezone
but then the column doesn't have TZ info
so when it gets inserted, the column loses TZ info
and then SpiceDB tries to convert it to UTC
and that's sent back into Postgres
but now its in UTC, so its the wrong time
the real question is why I can't reproduce the issue
but perhaps my postgres default is different
either way, it seems to be something we need to address
p
i just tried to change the timezone of postgres to 0 (UTC) still same issue...
j
won't matter unless you insert a new relationship
p
jeah i did...
but im just stupid i think
set timezone=0 seems to not have affected the now() in the default of the column... it still adds them in UTC+1
j
hrmph
maybe its a startup setting
or just system time
I think that's it
my tests were against postgres running in a container
which has 
date
as UTC
but you're running postgres on your machine, I believe
so that's likely the root reason
p
yes i do
in my opinion still a issue that timezones can mess it up
j
yep
its a bug
just glad we know why
we'll look into it tomorrow
p
dont worry... thanks for your help ^^
btw 
ALTER DATABASE "MyDBNameHere" SET timezone TO 'UTC';
and then restarting spicedb that worked
now spicedb behaves as intended
j
Good to know
2 Views
PreviousNext
Powered by